Skip to content

fix(relay): non-blocking stdout log writer so a stalled log copier can't wedge the runtime - #3256

Open
tlongwell-block wants to merge 4 commits into
mainfrom
eva/nonblocking-log-writer
Open

fix(relay): non-blocking stdout log writer so a stalled log copier can't wedge the runtime#3256
tlongwell-block wants to merge 4 commits into
mainfrom
eva/nonblocking-log-writer

Conversation

@tlongwell-block

@tlongwell-block tlongwell-block commented Jul 28, 2026

Copy link
Copy Markdown
Collaborator

Problem

Relay pods go deaf and die with exit 137 (liveness kills — up to 41/day fleet-wide). Root-caused by local reproduction at the deployed SHA: the tracing fmt layer writes JSON logs synchronously to stdout. In Kubernetes, stdout is a pipe drained by containerd's log copier. When the copier stalls (node disk-IO pressure, log rotation), the ~64KB pipe fills, the next write(2) blocks while holding Rust's global stdout lock, and every Tokio worker that logs queues behind it. The whole runtime parks in ~8s: liveness probes time out, SIGTERM (an async task) can never run, kubelet waits the full 60s grace and SIGKILLs.

Worker-thread count does not help — measured identical time-to-deaf at 2 and 8 workers (stdout is one global mutex, logging is on every hot path).

Repro evidence: RESEARCH/RELAY_STALL_LOCAL_REPRO_2026_07_27.md (Eva's nest) — SIGSTOP-the-consumer reproduces the full prod signature on demand, thread dumps show workers wedged in Stdout::write_all → write(2).

Fix

Route stdout through tracing_appender::non_blocking in lossy mode: the only blocking syscall moves to one dedicated OS thread behind a bounded queue. A stalled copier now costs dropped log lines, never a wedged runtime. Design reviewed and independently converged on by Wren (buzz-development thread).

  • logging::non_blocking_stdout() — explicit lossy(true) + buffered_lines_limit(4096). Limit is byte-budget-derived from measured prod line sizes (bb-block fleet sample, 26k lines: p50=248B, largest observed 641B — note p99 = max in that sample, so the true tail may be slightly larger; the byte budget has ample headroom either way): 4096 × 641B ≈ 2.6MB worst-case queue memory against a 2Gi limit. The buffer absorbs bursts; it is deliberately not sized to ride out a sustained copier outage.
  • logging::spawn_drop_counter_poller() — polls the writer's cumulative ErrorCounter and emits deltas into the monotonic counter buzz_log_lines_dropped_total (counter, not gauge; never logs — the log channel is exactly what has failed when it fires). Any positive rate = a copier stall that would previously have killed the pod, so this doubles as a permanent detector.
  • logging::BoundedWorkerGuard (added in review, e1a810371) — wraps the upstream WorkerGuard so that guard drop is bounded even when stdout is wedged. Review finding (Dawn reproduced it standalone; Max flagged the same path from source): upstream WorkerGuard::drop, when the queue is full, times out its 100ms shutdown send and then println!s — into the exact stdout whose lock the worker holds while parked in write(2). That deadlocks shutdown in precisely the failure mode this PR fixes. The wrapper runs the upstream drop on a sacrificial named thread and waits ≤2s (upstream's healthy drop is internally bounded at ~1.1s): healthy shutdown keeps the full flush; a wedged pipe costs the queued lines (already this module's stated loss policy) and process exit reaps the abandoned thread. If thread spawn fails, the guard is leaked, never dropped inline — lost lines, never a hang.
  • Guard held as a named _log_guard through all of main (binding to bare _ drops it immediately and silently discards all logs — documented + tested).
  • Whole-line atomicity comes free: fmt hands the writer a complete serialized line and admission is a single try_send, so no partial/corrupt JSON lines ever reach the pipe.

Direct-write audit: all 12 eprintln! sites in buzz-relay are inside #[cfg(test)] modules; no prod-reachable println!/eprintln! bypasses the writer.

Verification

Unit tests (6 in logging.rs): blocked-sink invariant (blocked writer + queue over capacity leaves the runtime responsive, memory bounded, drops counted, output recovers on unblock), end-to-end delivery, drop-counter delta semantics, oversized-line whole-line atomicity, bounded-guard healthy-path flush, and a subprocess-level wedged-shutdown regression: the test re-execs itself with stdout piped and never read, saturates pipe + queue (proven via dropped_lines() > 0, reported over stderr since stdout can't carry a readiness signal once wedged), drops the guard, and asserts clean bounded exit. Verified the test catches the bug: with the raw upstream drop inlined, the child hangs and the test fails on its deadline.

Live repro at b03bf2d8b (release build, 2 tokio workers, stdout piped to a SIGSTOP-able consumer — the rig that reproduced the prod failure):

Check Old behavior At b03bf2d8b
Liveness during 5-min copier stall deaf in ~8s 416+ probes, zero failures, worst latency 3.5ms
RSS during stall n/a (dead) 31.2MB → 32.8MB plateau (bounded queue)
Drop counter n/a 358 → 3,090, rising monotonically
SIGCONT recovery n/a buffered lines flush, live logging resumes immediately

⚠️ An earlier revision of this table claimed "graceful drain, clean exit in 5.1s with the consumer still SIGSTOPped" for SIGTERM-during-stall. That claim was wrong for the queue-full case: Dawn's standalone repro shows upstream guard drop hanging indefinitely when the queue is saturated (that run must not have had a full queue at SIGTERM time). e1a810371 fixes the deadlock; a fresh live E2E at the new head — including SIGTERM while buzz_log_lines_dropped_total is actively incrementing — is being run before merge (Perci).

Full relay suite at e1a810371: 771 passed, 1 failed — api::mesh_demo::tests::demo_join_forwarded_arm_round_trips_echo, verified pre-existing on clean be13b4bb9 (main). fmt + clippy clean.

Follow-ups (separate PRs):

  • buzz-push-gateway still uses a plain blocking tracing_subscriber::fmt().json().init() (crates/buzz-push-gateway/src/main.rs:22) and is deployed with a liveness probe — same failure class (Dawn's review finding). Tracked so it isn't a discovery during the next incident.
  • pack_cache sync remove_dir_allspawn_blocking.

…n't wedge the runtime

The relay logs JSON lines synchronously to stdout. In Kubernetes stdout is
a pipe drained by the container runtime's log copier; when that copier
stalls (node disk-IO pressure, rotation), the ~64KB pipe fills and the next
write(2) blocks while holding Rust's global stdout lock. Every worker that
logs then queues behind it: the whole Tokio runtime parks, liveness probes
time out, the SIGTERM handler (itself an async task) can never run, and
kubelet SIGKILLs the pod after the full 60s grace (exit 137). This is the
fleet-wide liveness-kill signature (1 -> 41 kills/day scaling with load).
Reproduced deterministically by SIGSTOP-ing a pipe consumer; worker-thread
count does not mitigate (measured identical at 2 and 8 workers).

Fix: route the fmt layer through tracing_appender::non_blocking in lossy
mode - the only blocking syscall moves to one dedicated OS thread behind a
bounded queue. A stalled copier now costs dropped log lines instead of a
dead relay.

- buffered_lines_limit(4096): derived from measured prod line sizes
  (p50=248B, p99=641B, max=641B over 26k lines) -> ~2.6MB worst-case queue
  memory, minutes of steady-state absorption.
- Dropped lines exported as monotonic counter buzz_log_lines_dropped_total
  (delta-polled from the appender's cumulative saturating ErrorCounter);
  doubles as a permanent copier-stall detector. The poller never logs -
  the log channel is exactly what has failed when it fires.
- WorkerGuard held as named _log_guard in main for the process lifetime
  (a bare _ binding would kill logging silently).
- Tests pin the motivating invariant: blocked sink + queue overrun leaves
  the runtime responsive, bounds memory, counts drops, and recovers output
  on unblock; plus end-to-end delivery through a real fmt layer, whole-line
  atomicity for oversized lines, and delta computation.

Prod-reachable direct println!/eprintln! sites: none (all 12 are inside
cfg(test) modules). Panic output goes to stderr (a separate pipe) on
terminal paths only - out of scope, cannot recreate the hot-path wedge.

Co-authored-by: Tyler Longwell <[email protected]>
Signed-off-by: Tyler Longwell <[email protected]>
@tlongwell-block
tlongwell-block requested a review from a team as a code owner July 28, 2026 02:12
…ed stdout

Review finding on #3256 (Dawn reproduced it standalone; Max flagged the
same path from source): upstream WorkerGuard::drop, when the queue is
full, times out its 100ms shutdown send and then println!s -- into the
exact stdout whose lock the worker thread holds while parked in write(2)
on the full pipe. Deadlock in the shutdown path of the change that exists
to fix shutdown. The prior tests missed it because both unblocked the
sink before dropping the guard.

Fix: BoundedWorkerGuard wraps the upstream guard and runs its drop on a
sacrificial named thread, waiting at most 2s (upstream's healthy drop is
internally bounded at ~1.1s). Healthy shutdown keeps the full flush;
a wedged pipe costs the queued lines -- already this module's stated
loss policy -- and process exit reaps the abandoned thread. If thread
spawn fails, the guard is leaked (ManuallyDrop), never dropped inline:
lost lines, never a hang. non_blocking_stdout() returns the wrapper, so
every exit path of main is covered with no call-site changes.

Tests:
- guard_drop_bounded_with_wedged_stdout_through_process_exit: subprocess
  regression at the process level. Child re-execs with stdout piped and
  never read (the exact production wedge), saturates pipe + queue
  (proven via dropped_lines() > 0, reported over stderr), drops the
  guard, exits; parent asserts clean exit within deadline. Verified the
  test catches the bug: with the raw upstream drop inlined it hangs the
  child and fails on the deadline.
- bounded_guard_flushes_on_healthy_shutdown: the wrapper still delivers
  the upstream flush when the sink is healthy.

Co-authored-by: Tyler Longwell <[email protected]>
Signed-off-by: Tyler Longwell <[email protected]>
npub1qyvc0c5kl4gqv2fd97fsk46tu378sqgy35vc83rvgfwne90sel7s0ed67d and others added 2 commits July 27, 2026 23:05
Max's re-review nit: the comment claimed p99=641B, max=641B — but p99
equaling max in a 26k-line sample means the tail was clipped by the
query, not observed, and 'worst-case' overstated what the sample proves.
Say what was actually measured and that the budget has headroom for a
fatter tail. Comment-only change.

Co-authored-by: Tyler Longwell <[email protected]>
Signed-off-by: Tyler Longwell <[email protected]>
Resolves conflict in crates/buzz-relay/src/main.rs: keep this branch's
non-blocking stdout writer (.with_writer(log_writer)) and adopt main's
per-layer env filters (log_env_filter / telemetry::otel_env_filter).

Co-authored-by: Tyler Longwell <[email protected]>
Signed-off-by: Tyler Longwell <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant